使用 JFR 镜像事件进行实验

Chris Hegarty 于 2021 年 6 月 4 日

本文档描述了在执行一项实验时的一些观察结果，该实验旨在确定在 JDK 的核心部分（特别是网络 API）中使用 JFR 镜像事件的可行性。镜像事件是 JDK 使用的一种内部机制，它不依赖于 jdk.jfr 模块，目前 java.base 中定义了唯一的镜像事件。由于镜像事件仅在 JDK 中可用，因此本文档中讨论的大部分内容与在 JDK 上工作的开发人员（而不是应用程序或库开发人员）直接相关，但某些问题和技术可能对更广泛的受众感兴趣。

A photo of car mirror
照片由 Hunter James 提供

在 JDK 中（特别是基本模块中）实现事件时，目前有几种方法：1）在 JVM 中进行本机实现，或 2）在运行时进行字节码插桩，或 3）使用镜像事件。第一种方法，即在 JVM 中进行本机实现，最适合 JVM 本身的低级操作，例如 GC 统计信息。对于监控 JDK 核心库，后两种方法，即字节码插桩或镜像事件更合适。但是哪种方法更好，它们之间的权衡是什么？本文档以一个特定的事件为例，提供了一些见解和分析来帮助回答这个问题。

目前（在 JDK 17 中），有一些 JFR 事件允许监控套接字读写操作。即，jdk.SocketReadEvent 和 jdk.SocketWriteEvent。这些事件能够监控 java.net.Socket 和 NIO SocketChannel 的 I/O。查看套接字或通道实现的源代码，没有对 JFR 或这些事件的引用，但与生成这些事件相关的代码是在运行时通过字节码插桩（套接字和通道实现类）执行的，此时 JFR 已启用。我们首先在记录现有套接字写入事件时生成性能数据，然后在将其重新实现为镜像事件时生成性能数据，最后我们将查看潜在改进的领域。

在深入研究套接字写入事件的细节之前，我们应该概述与事件的设计和实现相关的更高级别、更通用的考虑因素。

一般注意事项

在设计事件（或事件组）时，需要考虑的因素包括：1）我们想要公开的信息，2）收集和记录该信息的成本，以及 3）使用哪种类型的事件来传递该信息。

事件将以多高的频率触发？
事件是计时事件还是非计时事件？
事件是周期性事件还是按操作触发？

我们应该始终将用例放在设计的最前沿。我们试图帮助开发人员回答什么问题，我们希望提供什么关于系统的见解等等。

在分析事件对相关代码的影响时，存在多个问题

事件应该作为镜像事件写入，直接写入源代码实现中吗？
- 可维护性：易于维护
- 可读性：更多人查看代码，混乱吗？
- 性能：当 JFR 未启用时，性能影响有多大
- 可测试性：与回归测试位于同一位置
事件应该使用插桩技术吗？在这种技术中，字节码在运行时会插桩事件。
- 可维护性：更难维护，更脆弱
- 可读性：操作代码中的混乱更少
- 性能：当 JFR 未启用时，没有性能影响
- 可测试性：需要良好的测试覆盖率以确保没有问题

在性能方面存在多个问题

启动性能 - JFR 初始化和启动需要多长时间
- 更多的 Java 事件会导致更长的启动时间吗？
当 JFR 未启用时的运行时性能
当 JFR 已启用但特定事件未启用时的运行时性能
当 JFR 已启用且特定事件已启用时的运行时性能

本文档的其余部分将重点关注与运行时性能相关的后一个问题。

分析套接字写入事件

对于 JDK 核心库中的事件，一个重要的实现问题是使用字节码插桩还是镜像事件。我们将使用 JMH 基准测试来帮助回答这个问题。基准测试会对 SocketChannel 的一个方法进行测试，即 write(ByteBuffer)，可以将其视为其他执行 I/O 的方法的代表。

当 JFR 已启用时，调用 write 方法将记录一个 SocketWriteEvent。以下是此事件的声明

public final class SocketWriteEvent ... {
  @Label("Remote Host")
  public String host;

  @Label("Remote Address")
  public String address;

  @Label("Remote Port")
  public int port;

  @Label("Bytes Written")
  @Description("Number of bytes written to the socket")
  @DataAmount
  public long bytesWritten;
}

该事件捕获远程主机的名称、地址和端口号，以及写入的字节数。（还有其他未在此处显示的捕获值，例如开始时间和持续时间）

此事件使用字节码插桩技术实现，该技术在运行时转换 SocketChannelImpl 类的 write 方法。使用一个简单的基准测试，该基准测试与远程端点交换单个字节的数据，我们可以衡量记录此事件对写入操作整体性能的影响。然后，我们将重写代码，以便 SocketWriteEvent 使用镜像事件实现，并重新运行基准测试。比较前后，对于以下情况

JFR 已禁用
JFR 已启用，SocketWrite 事件已禁用：JFR-enabled-socketWrite-no
JFR 已启用，SocketWrite 事件已启用：JFR-enabled-socketWrite-yes

存在第四种情况，在本篇文章中不会考虑 - JFR 已启用，特定事件已启用，但未达到阈值。在监控非阻塞通道上的套接字写入时，通常需要将阈值设置为 0，记录所有事件。我们将在另一篇文章中回到第四种情况，因为它更复杂。

基准测试会生成单个基准测试调用的平均执行时间。分数越低越好。时间是在 Linux x86_64、Intel Xeon-8167M 2.00GHz 上测量的，运行使用 -prof gc 分析器（结果省略了一些输出行以提高可读性）。基准测试是 SocketChannelReadWrite 的修改版本，可以在此处找到。

基线 - JDK 17 EA

套接字写入事件使用字节码插桩实现。

Benchmark                                                                  (setupJFR)  Mode  Cnt    Score     Error   Units
SocketChannelReadWrite.test                                              JFR-disabled  avgt   50    2.234 ±   0.009   us/op
SocketChannelReadWrite.test:·gc.alloc.rate                               JFR-disabled  avgt   50   ≈ 10⁻⁴            MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm                          JFR-disabled  avgt   50    0.001 ±   0.001    B/op
SocketChannelReadWrite.test                                JFR-enabled-socketWrite-no  avgt   50    2.223 ±   0.006   us/op
SocketChannelReadWrite.test:·gc.alloc.rate                 JFR-enabled-socketWrite-no  avgt   50    0.007 ±   0.004  MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm            JFR-enabled-socketWrite-no  avgt   50    0.024 ±   0.013    B/op
SocketChannelReadWrite.test                               JFR-enabled-socketWrite-yes  avgt   50    3.058 ±   0.046   us/op
SocketChannelReadWrite.test:·gc.alloc.rate                JFR-enabled-socketWrite-yes  avgt   50   68.974 ±   3.317  MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm           JFR-enabled-socketWrite-yes  avgt   50  332.938 ±  20.804    B/op
SocketChannelReadWrite.test:·gc.churn.G1_Eden_Space.norm  JFR-enabled-socketWrite-yes  avgt   50  105.106 ± 286.331    B/op

我们可以看到，JFR 已禁用 和 JFR 已启用-socketWrite-no 的每次操作的平均时间非常相似，并且几乎没有分配 - 这在很大程度上要归功于优化的 Hotspot JIT 编译器。对于 JFR 已启用-socketWrite-yes，每次操作的时间会增加（这是预期的），并且分配以每操作 332 字节的标准化速率发生（其中大部分是 churn）。

请注意，基准测试并不真正代表现实世界的应用程序，因为它只是不断地写入单个字节（在我的机器上，每次迭代大约 400 万次）。因此，当事件启用时，每次操作的成本不应被视为此事件开销的一般指示，因为它在写入大量数据时会很大程度上被摊销，其中大部分时间都花在执行 I/O 上。为了分析目的，我们希望减少花费在 I/O 上的时间，以便我们可以专注于事件开销，因此使用单个字节。

使用镜像事件

在本轮测试中，套接字写入事件使用基础模块中的镜像事件重新实现（代码变更请参见此处）。确定事件实际捕获数据的代码与之前测试中字节码插桩版本的代码基本相同，但在此实现中，每个事件都会分配一个镜像事件对象。

Benchmark                                                                      (setupJFR)  Mode  Cnt    Score     Error   Units
SocketChannelReadWrite.test                                                  JFR-disabled  avgt   50    2.220 ±   0.014   us/op
SocketChannelReadWrite.test:·gc.alloc.rate                                   JFR-disabled  avgt   50   ≈ 10⁻⁴            MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm                              JFR-disabled  avgt   50    0.001 ±   0.001    B/op
SocketChannelReadWrite.test                                    JFR-enabled-socketWrite-no  avgt   50    2.220 ±   0.010   us/op
SocketChannelReadWrite.test:·gc.alloc.rate                     JFR-enabled-socketWrite-no  avgt   50    0.007 ±   0.004  MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm                JFR-enabled-socketWrite-no  avgt   50    0.025 ±   0.013    B/op
SocketChannelReadWrite.test                                   JFR-enabled-socketWrite-yes  avgt   50    3.123 ±   0.040   us/op
SocketChannelReadWrite.test:·gc.alloc.rate                    JFR-enabled-socketWrite-yes  avgt   50   81.809 ±   5.572  MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm               JFR-enabled-socketWrite-yes  avgt   50  401.742 ±  25.480    B/op
SocketChannelReadWrite.test:·gc.churn.G1_Eden_Space.norm      JFR-enabled-socketWrite-yes  avgt   50  155.162 ± 380.211    B/op

我们可以看到，对于JFR-禁用和JFR-启用-socketWrite-no，每个操作的平均时间和归一化分配率与之前的基线测试非常相似。对于JFR-启用-socketWrite-yes，分配以每操作 401 字节的归一化速率发生，比基线测试增加了约 20%。

稍微调整一下

为了确定事件实际捕获的数据，特别是远程主机名和地址，需要运行一小段代码。这段代码通过使用公共 API 和字符串操作来检索主机名和地址 - 这不是最有效的方法，可能是我们分配的大部分原因？（当仅限于使用公共 API 时，此代码是合理的）。以下是代码

  String hostString  = isa.getAddress().toString();
  int delimiterIndex = hostString.lastIndexOf('/');
  event.host = hostString.substring(0, delimiterIndex);
  event.address = hostString.substring(delimiterIndex + 1);

在镜像事件版本中，代码位于基础模块中，与通道实现并排，因此我们可以允许自己自由地寻找更好的替代方案（不使用公共 API）。一个立即想到的选项是扩展 Net 共享密钥，以从 InetAddress 返回主机名字符串。地址可以从InetAddress::getHostAddress() 中检索。以下代码是功能等效的

  InetAddress address = isa.getAddress();
  var h = JNINA.hostnameValue(address);
  event.host = h == null ? "" : h;
  event.address = address.getHostAddress();
  event.port = isa.getPort();

让我们再次使用此代码运行基准测试

Benchmark                                                                  (setupJFR)  Mode  Cnt    Score    Error   Units
...
SocketChannelReadWrite.test                               JFR-enabled-socketWrite-yes  avgt   50    2.869 ±  0.022   us/op
SocketChannelReadWrite.test:·gc.alloc.rate                JFR-enabled-socketWrite-yes  avgt   50   40.773 ±  0.319  MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm           JFR-enabled-socketWrite-yes  avgt   50  184.139 ±  0.029    B/op
SocketChannelReadWrite.test:·gc.churn.G1_Eden_Space.norm  JFR-enabled-socketWrite-yes  avgt   50   55.492 ± 60.860    B/op

我们可以看到，每个操作的时间有所改善，分配量也减少了。事实上，与基线相比，每个操作的时间只略有改善，但分配量减少了约 45%。

但我们还可以做得更多。如果我们缓存连接通道的主机名和地址呢？

Benchmark                                                                  (setupJFR)  Mode  Cnt   Score    Error   Units
SocketChannelReadWrite.test                                   JFR-enabled-socketWrite-yes  avgt   50   2.718 ±  0.042   us/op
SocketChannelReadWrite.test:·gc.alloc.rate                    JFR-enabled-socketWrite-yes  avgt   50  11.274 ±  0.180  MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm               JFR-enabled-socketWrite-yes  avgt   50  48.221 ±  0.133    B/op
SocketChannelReadWrite.test:·gc.churn.G1_Eden_Space.norm      JFR-enabled-socketWrite-yes  avgt   50  50.237 ± 50.490    B/op

我们可以看到，每个操作的时间开销和分配开销都显著降低。与基线相比，每个操作的时间减少了 10%，分配减少了 85%。这似乎表明，分配开销的大部分与确定事件数据值的代码有关，而不是与事件本身（及其基础设施）有关。

最后，为了“比较苹果和苹果”，以下是运行字节码插桩套接字写入事件的结果，该事件访问缓存的主机名和地址字段

SocketChannelReadWrite.test                      JFR-enabled-socketWrite-yes  avgt   50   2.630 ±  0.015   us/op
SocketChannelReadWrite.test:·gc.alloc.rate       JFR-enabled-socketWrite-yes  avgt   50   0.030 ±  0.007  MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm  JFR-enabled-socketWrite-yes  avgt   50   0.123 ±  0.029    B/op
SocketChannelReadWrite.test:·gc.count            JFR-enabled-socketWrite-yes  avgt   50     ≈ 0           counts

我们可以看到，每个操作的时间略小于之前的镜像事件运行，并且分配几乎完全消除。这可能是最好的结果，但正如我们所见，可以用提供更好性能和分配性能特征的镜像事件替换现有的字节码插桩套接字写入事件。

结论

镜像事件的设计要求在每次引发事件时创建一个事件对象，但这本身不应是设计和实现事件时的主要关注点。相反，应该将总的性能和分配影响作为一个整体来考虑。从这个特定实验中可以清楚地看出，确定事件实际捕获数据的代码可能会比用于实现事件的机制对性能产生更大的影响。此外，使用镜像事件允许实现更自由地编码这种确定（更多更轻松地访问私有内部）。